Closed Bug 425897 Opened 17 years ago Closed 17 years ago

Tb goes offline after hibernation on Vista

Categories

(Thunderbird :: General, defect)

x86
Windows Vista
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: mahowi, Unassigned)

Details

Attachments

(2 files, 2 obsolete files)

User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.0; de; rv:1.9b4) Gecko/2008030714 Firefox/3.0b4 Mnenhy/0.7.5.20005 Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 6.0; de-DE; rv:1.9b5pre) Gecko/2008032602 Thunderbird/3.0a1pre ID:2008032602 When Vista "wakes up" after hibernation, Thunderbird is offline and could not be set online again. You have to restart Thunderbird to go online again. Reproducible: Always Steps to Reproduce: 1. hibernate Vista with Thunderbird online 2. start Vista again Actual Results: Thunderbird is offline Expected Results: Thunderbird should be in the same state as before hibernation
Version: unspecified → Trunk
Problem appears also in Safe-Mode and seems to exist only in Vista. According to the german newsgroup "de.comm.software.mozilla.nightly-builds" there's no problem with hibernation on XP.
Summary: Tb goes offline after hibernation → Tb goes offline after hibernation on Vista
As a workaround it helps to set "offline.autoDetect" to false.
Phil, if you are running Vista, could you please confirm this issue.
Nope, no Vista here.
(In reply to comment #0) > When Vista "wakes up" after hibernation, Thunderbird is offline and could not > be set online again. You have to restart Thunderbird to go online again. When offline.autoDetect=true, I think entering to offline temporary itself is natural behavior, because "power-off and power-on again" occurs on network card too when hibernation(suspend/resume). I guess problem exists around "can't set online again" part. There are some reports of phenomenon that Firefox can't access Web after "wake up" on Vista - Bug 410363, Bug 411258, Bug 412544, Bug 419541, Bug 424559. (Sorry but I dont't know whether problem when suspend/resume is involved or not) And Bug 411258 has reported phenomenon of "loss of loopback socket". Same question as Bug 411258 Comment #1. What does "netstat -b -o" say when problem occurs?
C:\Windows\system32>netstat -b -o Aktive Verbindungen Proto Lokale Adresse Remoteadresse Status PID [...] [thunderbird.exe] TCP 127.0.0.1:61873 marvin:61872 HERGESTELLT 8076 [thunderbird.exe] TCP 127.0.0.1:61877 marvin:61878 HERGESTELLT 8076 [thunderbird.exe] TCP 127.0.0.1:61878 marvin:61877 HERGESTELLT 8076 [thunderbird.exe] TCP 127.0.0.1:62527 marvin:44080 WARTEND 0 TCP 127.0.0.1:62528 marvin:44080 WARTEND 0 TCP 127.0.0.1:62533 marvin:44080 WARTEND 0 TCP 192.168.178.21:61421 190-38-186-235:57983 FIN_WARTEN_1 7096 [...] HERGESTELLT = ESTABLISHED WARTEND = WAITING FIN_WARTEN_1 = FIN_WAIT_1
BTW, no problems here with Fx 3.0b4 after hibernation. I don't know if the "offline.autoDetect" option exists in Tb2 or is set to false by default, but it never went offline after hibernation. If I manually set Tb to offline I can set it online again without problems.
Some work was done in bug 359134 You might want to check the behaviors of toggling the following prefs: network.autodial-helper.enabled offline.autoDetect
Toggling "network.autodial-helper.enabled" doesn't help. Setting "offline.autoDetect" to false helps as reported above. But as WADA said in #5, the problem is, that Tb can not go online again without restart.
When Tb trunk(2008/4/02 build, Win-XP SP2), default is network.autodial-helper.enabled=true & offline.autoDetect=true, but "entering to offline mode on quick-resume/resume" can not be observed with MS Win-XP SP2 on My PC(core2 duo). This is probably by improvement of Bug 197863 ("sleep_notification" & "wake_notification" is newly handled). When MS Windows Vista, offline.autoDetect=true seems to interfere the action by this improvement. (A) "Error notification on quick-resume(wake-up)/resume by Vista" is done at very early stage of quick-resume/resume when Vista, then offline.autoDetect=true works first, or (B) "wake_notification by Vista" is too late for current Tb's logic, then offline.autoDetect=true works first. I suspect (A).
FYI. Default of related options (on MS Win-XP SP2) : Tb 2.0.0.12 Tb_Trunk(2008/4/02 build) network.autodial-helper.enabled true true offline.autoDetect true true > http://lxr.mozilla.org/seamonkey/source/mailnews/extensions/offline-startup/js/offlineStartup.js#80 > Sets manageOfflineStatus from offline.autoDetect > http://lxr.mozilla.org/seamonkey/source/netwerk/base/src/nsIOService.cpp#690 > nsIOService::PrefsChanged > Sets enableAutodial from network.autodial-helper.enabled > http://lxr.mozilla.org/seamonkey/source/netwerk/base/src/nsIOService.cpp#897 > nsIOService::TrackNetworkLinkStatusForOffline As written by Joe Sabash in Comment #8, logic depends on : > (a) manageOfflineStatus ( offline.autoDetect ) > (b) enableAutodial ( network.autodial-helper.enabled ) > (c) When MS_WIN, whether autodial is enabled at the OS level, or not (In reply to comment #9) > Toggling "network.autodial-helper.enabled" doesn't help. > Setting "offline.autoDetect" to false helps as reported above. I think this result fits with logic in TrackNetworkLinkStatusForOffline.
(In reply to comment #11) > Default of related options (on MS Win-XP SP2) : > Tb 2.0.0.12 Tb_Trunk(2008/4/02 build) > network.autodial-helper.enabled true true > offline.autoDetect true true > This is also the default on Vista. > As written by Joe Sabash in Comment #8, logic depends on : > > (a) manageOfflineStatus ( offline.autoDetect ) > > (b) enableAutodial ( network.autodial-helper.enabled ) > > (c) When MS_WIN, whether autodial is enabled at the OS level, or not My computer is always online via cable. When I login after hibernation the connection is already established. So, because I don't have a dialup network, (b) and (c) shouldn't do anything. (In reply to comment #10) > When MS Windows Vista, offline.autoDetect=true seems to interfere the action by > this improvement. (A) "Error notification on quick-resume(wake-up)/resume by > Vista" is done at very early stage of quick-resume/resume when Vista, then > offline.autoDetect=true works first, or (B) "wake_notification by Vista" is too > late for current Tb's logic, then offline.autoDetect=true works first. I > suspect (A). > Because I'm already online when logging in, I also suspect (A). Tb seems to trigger the online status in a very early stage after wake-up. Other programs like e.g. Firefox (3.0b5) can go online directly after login.
NSPR log data with all:5 on MS Win-XP SP2. >(Note: Log seq number & timestamp is added by DebugView) > 00000164 15.00269794 [3036] 4056[16d80c0]: timeout = 65535000 milliseconds >(Stand-By & Wake-up here) > 00000165 54.52249908 [3036] 0[3c4618]: Computing ranges for string: (len = 2) >(Re-draw of Tb's window) > 00000801 54.61824036 [3036] 0[3c4618]: - Using MS UI Gothic > 00000802 54.61827087 [3036] 0[3c4618]: Found 1 ranges >(Network environment is back) > 00000803 64.70861816 [3036] 0[3c4618]: nsHttpHandler::Observe [topic="timer-callback"] > 00000804 64.70914459 [3036] 0[3c4618]: STS dispatch [3c255d8] > 00000805 64.70948792 [3036] 0[3c4618]: send: fd=16d5cb0 osfd=504 buf=6001d56d amount=1 > 00000806 64.71022034 [3036] 0[3c4618]: send -> 1 > 00000807 64.71051788 [3036] 4056[16d80c0]: ...returned after 51379 milliseconds > 00000808 64.71084595 [3036] 4056[16d80c0]: recv: fd=16d5a28 osfd=468 buf=1abfa58 amount=1024 flags=0 > 00000809 64.71121979 [3036] 4056[16d80c0]: recv -> 1, error = -5998, os error = 0 > 00000810 64.71155548 [3036] 4056[16d80c0]: nsHttpConnectionMgr::OnMsgPruneDeadConnections It looks that send error at loopback, then polling error & connection error(OnMsgPruneDeadConnections).
As far as I can see, the problem is related to IMAP. If I disable all accounts or only enable POP3 accounts, Tb doesn't go offline after wake-up. If I enable an IMAP account, Tb goes offline after wake-up. I've uploaded a NSPR log(all:5) to http://www.mahowi.de/tb.log It's 1.8MB because of logging IMAP so I couldn't upload it to bugzilla.
Attached file NSPR log (all:5) TB trunk Vista (obsolete) —
I removed everything from startup to start of IMAP and the log of the junk filter to shrink the file below 300k.
Attachment #313613 - Attachment mime type: application/octet-stream → text/plain
(In reply to comment #15) > NSPR log (all:5) TB trunk Vista (A) In the log, where Stand By/Wake Up(or Suspend/Resume) was executed? (B) Funny flow is seen in your log. - "* STATUS Sent Items" response data which doesn't seem to be a response to 3 STATUS "Sent Items"(or 7 STATUS "Sent Items"). - This causes followig "PARSER:Internal Syntax Error" (See http://www.faqs.org/rfcs/rfc3501.html for IMAP Status Command/Response) There is something wrong in usual use of imap.strato.de, isn't it? > 98228[516dab8]: 54d6420:imap.strato.de:A:SendData: 3 STATUS "Sent Items" (UIDNEXT MESSAGES UNSEEN RECENT) >(snip) > 98228[516dab8]: 54d6420:imap.strato.de:A:CreateNewLineFromSocket: * STATUS Sent Items (MESSAGES 0 RECENT 0 UIDNEXT 1 UNSEEN 0) > 98228[516dab8]: 54d6420:imap.strato.de:A:PARSER:Internal Syntax Error on line: %s: * STATUS Sent Items (MESSAGES 0 RECENT 0 UIDNEXT 1 UNSEEN 0) > 41076[52b7f68]: 5304440:imap.strato.de:A:SendData: 7 STATUS "Sent Items" (UIDNEXT MESSAGES UNSEEN RECENT) >(snip) > 41076[52b7f68]: 5304440:imap.strato.de:A:CreateNewLineFromSocket: * STATUS Sent Items (MESSAGES 0 RECENT 0 UIDNEXT 1 UNSEEN 0) > 41076[52b7f68]: 5304440:imap.strato.de:A:PARSER:Internal Syntax Error on line: %s: * STATUS Sent Items (MESSAGES 0 RECENT 0 UIDNEXT 1 UNSEEN 0)
Attached file new NSPR log(all:5) (obsolete) —
New log. Now I marked where hibernation was.
> NSPR log It seems that response data from your IMAP server doesn't contain CRLF, thus next log data is merged in single log data line. > 102188[4d9e800]: 4fa98f0:imap.strato.de:NA:CreateNewLineFromSocket: * OK IMAP server ready [905] 0[2462f00]: Computing ranges for string: (len = 35) CRLF is usually placed after "OK IMAP server ready", then response data fro IMAP server usually becomes a single line in NSPR log file. RFC 3501 defines as follows. > 2.2. Commands and Responses >(snip) > All interactions transmitted by client and server are in the form of lines, > that is, strings that end with a CRLF. And your server doesn't quote folder name with space(e.g Sent Items) in STATUS response. Is your IMAP server properly set up?
It really seems to be a problem with my IMAP server. I have another 2 accounts on it where there are no problems. Only the one I tested here seems to be misconfigured. But why does Thunderbird go to offline mode if I enable this account? And why does this happen only after hibernation? I would expect an error message if the server doesn't behave as it should but not going offline.
(In reply to comment #19) > But why does Thunderbird go to offline mode if I enable this account? > And why does this happen only after hibernation? I have same questions as yours. My guess is as follows. (1) Your IMAP server apparently has errors at least: no CRLF in response & no quote of mbox name when mbox name with space (2) (1) makes wait condition in Tb at somewhere (3) On Stand-By/Quick-Resume(wake-up) or Suspend/Resume, if problem of (1)&(2) doesn't exist, Tb can keep online status by "sleep notification" support & "wakeup notification" support, even on MS Win Vista. However, due to (1)&(2), it doesn't work well, then process of "entering to offline" due to offline.autoDetect is invoked in your environment. (4) Due to (1)&(2)%(3), "entering to offline" hangs up at somewhere in Tb. (5) Thus, Tb can't get back "online status" via UI for reset "Work Offline". NSPR log doesn't have timestamp, and it makes problem analysis difficult. Get NSPR log with timestamp by DebugView. (See Bug 411258 Comment#10) And check what is happening before/during wake-up.
new log again, this time with DebugView: 00001705 23.76668549 [103972] 108496[2df8348]: STS poll iter [0] 00001706 23.76674080 [103972] 108496[2df8348]: active [2] { handler=51dde28 condition=0 pollflags=5 } 00001707 23.76686859 [103972] 108496[2df8348]: active [1] { handler=51def60 condition=0 pollflags=5 } 00001708 23.76692200 [103972] 108496[2df8348]: active [0] { handler=51df048 condition=0 pollflags=5 } 00001709 23.76697350 [103972] 108496[2df8348]: calling PR_Poll [active=3 idle=0] 00001710 23.76702499 [103972] 108496[2df8348]: poll timeout: 5 00001711 23.76710129 [103972] 108496[2df8348]: timeout = 0 milliseconds 00001712 23.76715469 [103972] 108496[2df8348]: ...returned after 0 milliseconds 00001713 23.76720619 [103972] 108496[2df8348]: STS poll iter [1] 00001714 23.76725769 [103972] 108496[2df8348]: active [2] { handler=51dde28 condition=0 pollflags=5 } 00001715 23.76730919 [103972] 108496[2df8348]: active [1] { handler=51def60 condition=0 pollflags=5 } 00001716 23.76736259 [103972] 108496[2df8348]: active [0] { handler=51df048 condition=0 pollflags=5 } 00001717 23.76741409 [103972] 108496[2df8348]: calling PR_Poll [active=3 idle=0] 00001718 23.76746368 [103972] 108496[2df8348]: poll timeout: 5 00001719 23.76750565 [103972] 108496[2df8348]: timeout = 5000 milliseconds [hibernation happens here] 00001720 1033.89868164 [103972] 102968[54e2ea0]: nsHostResolver::ThreadFunc exiting 00001721 1033.89904785 [103972] 102968[54e2ea0]: thread exiting 00001722 1033.90270996 [103972] 108496[2df8348]: ...returned after 1009914 milliseconds 00001723 1033.90820313 [103972] 108496[2df8348]: nsSocketTransport::OnSocketReady [this=51dde28 outFlags=-1] 00001724 1033.92639160 [103972] 108496[2df8348]: socket timeout expired [...] I found out something interesting again. Failure happens only with junk filter enabled! If I disable the junk filter Tb remains online. So this bug's getting very strange now. To summarize: Bug happens only with IMAP *AND* junk filter enabled.
Attachment #313613 - Attachment is obsolete: true
Attachment #313787 - Attachment is obsolete: true
(In reply to comment #21) > To summarize: Bug happens only with IMAP *AND* junk filter enabled. FYI. Problem on IMAP like next is possibly involved in hung of IMAP just after hibernate. > Bug 410747 – IMAP code deadlocks when it can't reach the network See also Bug 431460 for potential deadlock in IMAP.
Now Tb goes online again after hibernation. Unfortunately I don't know which build fixed it.
Status: UNCONFIRMED → RESOLVED
Closed: 17 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: